zms[5287]: ERR [Unable to authenticate user]

[zoneminder]

Tek - It appears that the directory you have created for your logs (and possibly your sockets) does not have permissions for your web user to write to it. This is required.

Oskin - Thanks, I've made similar changes here and will do a 1.20.1 very soon. I'm still not sure why Ross et all don't get any auth string passed in though, as that seems to be the major issue.

Phil

[rdmelin]

Sorry for the long delay in replying. I was away most of the day.

I assume you have ZM_AUTH_OPT on by the way, I know there is definitely a problem when it's off but I'd rather wait until I fix this one before putting out an update.

No I have to leave ZM_OPT_USE_AUTH off because I cannot login if I turn it on.

Ross

[zoneminder]

Ok. That's sort of good. I know, and have fixed the issue when auth is off. I'm still unsure of why some people are having trouble logging in. Do you have any other diagnostics that might help?

Cheers

Phil

[securiteaze]

apache2 error_log:

Code: Select all

[Mon Jan 24 00:07:12 2005] [info] Server: Apache/2.0.52, Interface: mod_ssl/2.0.52, Library: OpenSSL/0.9.7d
[Mon Jan 24 00:07:12 2005] [notice] Apache/2.0.52 (Gentoo/Linux) mod_ssl/2.0.52 OpenSSL/0.9.7d PHP/4.3.10 configured -- resuming normal operations
[Mon Jan 24 00:07:12 2005] [info] Server built: Dec  1 2004 15:11:07
Error, unable to authenticate user
[Mon Jan 24 00:08:32 2005] [error] [client 192.168.254.192] Premature end of script headers: zms, referer: http://192.168.254.2/index.php?view=watchfeed&mode=&mid=1&scale=100
Error, unable to authenticate user
Error, unable to authenticate user
Error, unable to authenticate user

syslog:

Code: Select all

Jan 24 00:08:22 optix apache2: PHP Notice:  import_request_variables(): No prefix specified - possible security hazard in /www/zm.php on line 21
Jan 24 00:08:32 optix zms[5642]: ERR [skjhdAKJSKJ^@$.<sdjskjJSHAKHDSdjhekjdfkhd34434243admin60e4474e10a2bb15192.168.254.1920240105 -> ]
Jan 24 00:08:32 optix zms[5642]: ERR [skjhdAKJSKJ^@$.<sdjskjJSHAKHDSdjhekjdfkhd34434243admin60e4474e10a2bb15192.168.254.19223230105 -> ]
Jan 24 00:08:32 optix zms[5642]: ERR [skjhdAKJSKJ^@$.<sdjskjJSHAKHDSdjhekjdfkhd34434243USERANAME034c30ad18d03ccc192.168.254.1920240105 -> ]
Jan 24 00:08:32 optix zms[5642]: ERR [skjhdAKJSKJ^@$.<sdjskjJSHAKHDSdjhekjdfkhd34434243USERANAME034c30ad18d03ccc192.168.254.19223230105 -> ]
Jan 24 00:08:32 optix zms[5642]: ERR [skjhdAKJSKJ^@$.<sdjskjJSHAKHDSdjhekjdfkhd34434243USERBNAME53419ce64d562fd8192.168.254.1920240105 -> ]
Jan 24 00:08:32 optix zms[5642]: ERR [skjhdAKJSKJ^@$.<sdjskjJSHAKHDSdjhekjdfkhd34434243USERBNAME53419ce64d562fd8192.168.254.19223230105 -> ]
Jan 24 00:08:32 optix zms[5642]: ERR [Unable to authenticate user]

Log in as admin and everything works.
Logging in as any other user, regardless of their privileges, results with the prior messages. I have applied oskin's zm_user.cpp patch also.

[oskin]

I was helped by such diagnostics:

Code: Select all

--- zm_user.cpp.orig    2005-01-24 10:16:57.592166036 +0300
+++ zm_user.cpp 2005-01-24 10:21:06.440364505 +0300
@@ -200,6 +200,7 @@
                                now_tm->tm_year
                        );

+Error(("auth_key: [%s]\n", auth_key));
                        MD5( (unsigned char *)auth_key, strlen(auth_key), md5sum );
                        auth_md5[0] = '\0';
                        for ( int j = 0; j < MD5_DIGEST_LENGTH; j++ )
@@ -211,8 +212,11 @@
                        {
                                // We have a match
                                User *user = new User( dbrow );
+Error(("auth OK - user: %s, auth_md5: %s\n", user->getUsername(), auth_md5));
                                Info(( "Authenticated user '%s'", user->getUsername() ));
                                return( user );
+                       } else {
+Error(("auth BAD - user: %s, auth: [%s], auth_md5: [%s]\n", user, auth, auth_md5));
                        }
                }
        }

[rmo]

With the zm_user.cpp patch from oskin it is working for me
on SuSE 9.2 .


Thanks

rmo

[zoneminder]

Ack. securiteaze and others, the Info line I suggested I put ahead of the for loop so you might need to move it down to get anythign sensible from it.

I'm a little confused about where everyone is on this issue now and who's still having a problem and if so which one.

Phil

[loop]

Perhaps you can post the patches/help here once again, so we can try them out. Don't know from the thread which is the correct way solve the problems.
I'd be glad to test the patch(es).

DN

[tek]

Tek - It appears that the directory you have created for your logs (and possibly your sockets) does not have permissions for your web user to write to it. This is required.

Thanks that got it to start and i have lots of new logging now and i can see the camera is streaming but i still have no image,here is the output of all the logging, i bumped up some iptables logging to verify what is happening.


tail -f /var/log/messages /var/log/zoneminder/*
==> /var/log/messages <==
Jan 24 03:40:04 superbox zma_m3[21088]: WAR [Waiting for capture daemon]
Jan 24 03:40:04 superbox snmpd[2179]: Connection from 127.0.0.1
Jan 24 03:40:05 superbox last message repeated 7 times
Jan 24 03:40:05 superbox zma_m3[21088]: WAR [Waiting for capture daemon]
Jan 24 03:40:05 superbox snmpd[2179]: Connection from 127.0.0.1
Jan 24 03:40:06 superbox last message repeated 6 times
Jan 24 03:40:06 superbox zma_m3[21088]: WAR [Waiting for capture daemon]
Jan 24 03:40:06 superbox snmpd[2179]: Connection from 127.0.0.1
Jan 24 03:40:07 superbox last message repeated 2 times
Jan 24 03:40:07 superbox zma_m3[21088]: WAR [Waiting for capture daemon]

==> /var/log/zoneminder/zmaudit.log <==

==> /var/log/zoneminder/zmdc.log <==
'zmc -m 3' started at 05/01/24 03:37:26
'zmc -m 3' died at 05/01/24 03:37:26, signal 10
Starting pending process, zmc -m 3
'zmc -m 3' starting at 05/01/24 03:38:06, pid = 21208
'zmc -m 3' started at 05/01/24 03:38:06
'zmc -m 3' died at 05/01/24 03:38:06, signal 10
Starting pending process, zmc -m 3
'zmc -m 3' starting at 05/01/24 03:39:26, pid = 21299
'zmc -m 3' started at 05/01/24 03:39:26
'zmc -m 3' died at 05/01/24 03:39:26, signal 10

==> /var/log/zoneminder/zmfilter.log <==
Scanning for events
Scanning for events
Scanning for events
Scanning for events
Scanning for events
Scanning for events
Scanning for events
Scanning for events
Scanning for events

==> /var/log/zoneminder/zmpkg.log <==
Removing shared memory
Executing: /usr/local/bin/zmfix
Executing: /usr/local/bin/zmdc.pl status
Executing: /usr/local/bin/zmdc.pl start zmc -m 3
Executing: /usr/local/bin/zmdc.pl start zmf -m 3
Executing: /usr/local/bin/zmdc.pl start zma -m 3
Executing: /usr/local/bin/zmdc.pl start zmfilter.pl
Executing: /usr/local/bin/zmdc.pl start zmaudit.pl -d 900 -y
Executing: /usr/local/bin/zmdc.pl start zmwatch.pl
Executing: /usr/local/bin/zmdc.pl start zmupdate.pl -c

==> /var/log/zoneminder/zmupdate.log <==
Update agent starting at 05/01/24 01:04:41
Update agent starting at 05/01/24 01:50:35
Update agent starting at 05/01/24 01:52:43
Update agent starting at 05/01/24 01:58:58
Update agent starting at 05/01/24 02:22:32
Update agent starting at 05/01/24 02:37:57
Update agent starting at 05/01/24 02:45:46
Update agent starting at 05/01/24 02:59:19
Update agent starting at 05/01/24 03:09:08
Update agent starting at 05/01/24 03:36:54

==> /var/log/zoneminder/zmwatch.log <==
Watchdog starting at 05/01/24 02:37:56
Watchdog pausing for 30 seconds
Watchdog starting at 05/01/24 02:45:45
Watchdog pausing for 30 seconds
Watchdog starting at 05/01/24 02:59:18
Watchdog pausing for 30 seconds
Watchdog starting at 05/01/24 03:09:07
Watchdog pausing for 30 seconds
Watchdog starting at 05/01/24 03:36:53
Watchdog pausing for 30 seconds

==> /var/log/messages <==
Jan 24 03:40:18 superbox last message repeated 11 times
Jan 24 03:40:19 superbox zms[21573]: ERR [Unable to authenticate user]
Jan 24 03:40:19 superbox zma_m3[21088]: WAR [Waiting for capture daemon]
Jan 24 03:40:33 superbox last message repeated 14 times
Jan 24 03:40:34 superbox zms[21584]: ERR [Unable to authenticate user]


By changing my settings i am able to get lots of traffic (noted by the wireless leds on my axis 206w) but in my logs all i see is this
tail -f /var/log/messages
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53323 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53324 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53325 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53326 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53327 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53328 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53329 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]
Jan 24 04:04:18 superbox kernel: Shorewall:all2all:ACCEPT:IN= OUT=eth2 SRC=192.168.0.100 DST=192.168.0.208 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=1901 DF PROTO=TCP SPT=53330 DPT=80 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 24 04:04:19 superbox zma_m3[23659]: WAR [Waiting for capture daemon]

[zoneminder]

I think this should be in a different thread now as it's not authentication realated but it looks to me like the path you have entered to get to your camera images is wrong. At least that's what

Code: Select all

Jan 24 04:04:18 superbox zmc_m3[23651]: ERR [Invalid response status 400: Bad Request]

suggests to me.

Phil

[securiteaze]

After reading this thread http://www.zoneminder.com/forums/viewtopic.php?t=4056
I tried logging in as a user, but this time I capitalized the first character of the username, lo and behold it zm worked as expected. WooHoo!!
I originally added the user with a capital letter, however previous versions of zm didn't seem to mind.

This is with oskin's zm_user.cpp patch.

Thanks to Phil and Oskin!

[rdmelin]

I have rebuilt oskins FC3 rpms for mandrake 10.1 and 10.0. I believe they have his patches detailed above applied.

Installation is pretty smooth on both 10.1 and 10.0.

I am happy to report that the login issue is not present with mandrake 10.1. It is still an issue on 10.0 installed from the rpm.

The ERR [Unable to authenticate user] problem is also still an issue with 10.0. I will report whether the same is true of 10.1 as soon as I get a 10.1 system with a video input set up.

Has it been determined for certain whether these are two different problems or the same problem showing up in two different ways? Does anyone have one and not the other?

Ross

[zoneminder]

AFAIK there is a definite problem with zms generating the authenticate error is authentication in generla is switched off. This I know about and have fixed (though not released) as has Oskin I think. There is also another unrelated issue about mixed case users names that has always been present but which has only just had any effect if you login using a different capitalisation. This I have a fix for also. There was a final issue with the user database read but I don't know if that has any practical effect other than possibly sometimes saying that users don't have permission for things when they should. The fix for this is done also.

I think that's it but there may be something else if anyone who has applied all the patches is still having problems.

Phil

[rdmelin]

Well Im not sure about "all the patches" but have now tested what oskin has applied in his rpm. The mixed case user names are not at issue here as all installs have been fresh and only the default "admin" exists.

On mandrake 10.1 I can both login as admin and view stream with no problems.

On 10.0 I can not do either. I dont detect any difference in behavior than when installed from unpatched source. Failed login attempts do not seem to generate errors in any logs that I have found.

If you can suggest any approach to debug this I will be happy to try it.

Ross

[zoneminder]

Is there a different version of php between 10.0 and 10.1?

Do you know if the userLogin function gets caled at all, and what it is passed if it is?

Phil